<html lang="en-US">

<head>
    
<title>Go 大杀器之跟踪剖析 trace - 花落雨忧</title>

<meta property="og:title" content="Go 大杀器之跟踪剖析 trace - 花落雨忧">



    



    
    <meta property="description" content="
在 Go 中有许许多多的分析工具，在之前我有写过一篇 《Golang 大杀器之性能剖析 PProf》 来介绍 PProf，如果有小伙伴感兴趣可以去我博客看看。
但单单使用 PProf 有时候不一定足够完整，因为在真实的程序中还包含许多的隐藏动作，例如 Goroutine 在执行时会做哪些操作？执行/阻塞了多长时间？在什么时候阻止？在哪里被阻止的？谁又锁/解锁了它们？GC &amp;hellip;">
    <meta property="og:description" content="
在 Go 中有许许多多的分析工具，在之前我有写过一篇 《Golang 大杀器之性能剖析 PProf》 来介绍 PProf，如果有小伙伴感兴趣可以去我博客看看。
但单单使用 PProf 有时候不一定足够完整，因为在真实的程序中还包含许多的隐藏动作，例如 Goroutine 在执行时会做哪些操作？执行/阻塞了多长时间？在什么时候阻止？在哪里被阻止的？谁又锁/解锁了它们？GC &amp;hellip;">
    






<meta http-equiv="Content-Type" content="text/html; charset=utf-8" />
<meta name="viewport" content="width=device-width,initial-scale=1">

<link rel="shortcut icon" href="https://www.lican.asia/logo/logo.png" type="image/x-icon" />



<link rel="stylesheet" href="/css/style.min.css" />

<link rel="stylesheet" href="/css/reset.min.css" />




<script src="https://www.lican.asia/js/highlight.min.js"></script>

<script>
hljs.configure({ ignoreUnescapedHTML: true })
hljs.highlightAll();
</script>


<script src="https://www.lican.asia/js/jquery.min.js"></script>




<link href="https://www.lican.asia/css/hugo-code.min.css" rel="stylesheet" />



    <style>
        .post-content img {
            max-width: 400px;
        }
    </style>
</head>

<body id="period" class="home blog">
    <a class="skip-content" href="#main">Press "Enter" to skip to content</a>
    <div id="overflow-container" class="overflow-container">
        <header class="site-header" id="site-header" role="banner">
    <div class="max-width">
        <div id="title-container" class="title-container">
            <div id="site-title" class="site-title"><a href="/">花落雨忧</a></div>
            <p class="tagline">思所及 力所行 方为真.</p>
        </div>
        
        <div id="menu-primary-container" class="menu-primary-container">
            <div class="icon-container">
            </div>
            <div id="menu-primary" class="menu-container menu-primary" role="navigation">
                <nav class="menu">
                    <ul id="menu-primary-items" class="menu-primary-items">
                        
                        
                        <li id="menu-item-0"
                            class="menu-item menu-item-type-custom menu-item-object-custom ">
                            <a href="/posts" aria-current="page" tabindex="0">首页</a></li>
                        
                        <li id="menu-item-1"
                            class="menu-item menu-item-type-custom menu-item-object-custom ">
                            <a href="/tech/" aria-current="page" tabindex="1">技术文档</a></li>
                        
                        <li id="menu-item-2"
                            class="menu-item menu-item-type-custom menu-item-object-custom ">
                            <a href="/article/" aria-current="page" tabindex="2">文章</a></li>
                        
                        <li id="menu-item-3"
                            class="menu-item menu-item-type-custom menu-item-object-custom ">
                            <a href="/project/" aria-current="page" tabindex="3">项目</a></li>
                        
                        <li id="menu-item-4"
                            class="menu-item menu-item-type-custom menu-item-object-custom ">
                            <a href="/about/" aria-current="page" tabindex="4">关于</a></li>
                        
                    </ul>
                </nav>
            </div>
        </div>
    </div>
</header>

        <div id="primary-container" class="primary-container">
            <div class="max-width">
                <section id="main" class="main" role="main">
                    <div id="loop-container" class="loop-container">
                        <div
                            class="post type-post status-publish format-standard hentry entry">
                            <article>
                                <div class="post-container">
                                    <div class="post-header">
                                        <h2 class="post-title">
                                            <a href="/posts/posts/go/tools/2019-07-12-go-tool-trace/">Go 大杀器之跟踪剖析 trace</a>
                                        </h2>
                                        
                                        <div class="post-byline">Published on
                                            <a class="date" href="javascript:;">2019/07/12</a>
                                            
                                            
                                            
                                            By 
                                            <a class="author" href="javascript:;">煎鱼</a></div>
                                            
                                        
                                    </div>
                                    <div class="post-content">
                                        <p><img src="https://s2.ax1x.com/2020/02/15/1x1phF.png" alt="image"></p>
<p>在 Go 中有许许多多的分析工具，在之前我有写过一篇 《Golang 大杀器之性能剖析 PProf》 来介绍 PProf，如果有小伙伴感兴趣可以去我博客看看。</p>
<p>但单单使用 PProf 有时候不一定足够完整，因为在真实的程序中还包含许多的隐藏动作，例如 Goroutine 在执行时会做哪些操作？执行/阻塞了多长时间？在什么时候阻止？在哪里被阻止的？谁又锁/解锁了它们？GC 是怎么影响到 Goroutine 的执行的？这些东西用 PProf 是很难分析出来的，但如果你又想知道上述的答案的话，你可以用本文的主角 <code>go tool trace</code> 来打开新世界的大门。目录如下：</p>
<p><img src="https://s2.ax1x.com/2020/02/15/1x1P1J.png" alt="image"></p>
<h2 id="初步了解">初步了解</h2>
<div class="highlight"><pre tabindex="0" style="color:#f8f8f2;background-color:#272822;-moz-tab-size:4;-o-tab-size:4;tab-size:4;"><code class="language-go" data-lang="go"><span style="display:flex;"><span><span style="color:#f92672">import</span> (
</span></span><span style="display:flex;"><span>	<span style="color:#e6db74">&#34;os&#34;</span>
</span></span><span style="display:flex;"><span>	<span style="color:#e6db74">&#34;runtime/trace&#34;</span>
</span></span><span style="display:flex;"><span>)
</span></span><span style="display:flex;"><span>
</span></span><span style="display:flex;"><span><span style="color:#66d9ef">func</span> <span style="color:#a6e22e">main</span>() {
</span></span><span style="display:flex;"><span>	<span style="color:#a6e22e">trace</span>.<span style="color:#a6e22e">Start</span>(<span style="color:#a6e22e">os</span>.<span style="color:#a6e22e">Stderr</span>)
</span></span><span style="display:flex;"><span>	<span style="color:#66d9ef">defer</span> <span style="color:#a6e22e">trace</span>.<span style="color:#a6e22e">Stop</span>()
</span></span><span style="display:flex;"><span>
</span></span><span style="display:flex;"><span>	<span style="color:#a6e22e">ch</span> <span style="color:#f92672">:=</span> make(<span style="color:#66d9ef">chan</span> <span style="color:#66d9ef">string</span>)
</span></span><span style="display:flex;"><span>	<span style="color:#66d9ef">go</span> <span style="color:#66d9ef">func</span>() {
</span></span><span style="display:flex;"><span>		<span style="color:#a6e22e">ch</span> <span style="color:#f92672">&lt;-</span> <span style="color:#e6db74">&#34;EDDYCJY&#34;</span>
</span></span><span style="display:flex;"><span>	}()
</span></span><span style="display:flex;"><span>
</span></span><span style="display:flex;"><span>	<span style="color:#f92672">&lt;-</span><span style="color:#a6e22e">ch</span>
</span></span><span style="display:flex;"><span>}
</span></span></code></pre></div><p>生成跟踪文件：</p>
<pre tabindex="0"><code>$ go run main.go 2&gt; trace.out
</code></pre><p>启动可视化界面：</p>
<pre tabindex="0"><code>$ go tool trace trace.out
2019/06/22 16:14:52 Parsing trace...
2019/06/22 16:14:52 Splitting trace...
2019/06/22 16:14:52 Opening browser. Trace viewer is listening on http://127.0.0.1:57321
</code></pre><p>查看可视化界面：</p>
<p><img src="https://s2.ax1x.com/2020/02/15/1x1FXR.png" alt="image"></p>
<ul>
<li>View trace：查看跟踪</li>
<li>Goroutine analysis：Goroutine 分析</li>
<li>Network blocking profile：网络阻塞概况</li>
<li>Synchronization blocking profile：同步阻塞概况</li>
<li>Syscall blocking profile：系统调用阻塞概况</li>
<li>Scheduler latency profile：调度延迟概况</li>
<li>User defined tasks：用户自定义任务</li>
<li>User defined regions：用户自定义区域</li>
<li>Minimum mutator utilization：最低 Mutator 利用率</li>
</ul>
<h3 id="scheduler-latency-profile">Scheduler latency profile</h3>
<p>在刚开始查看问题时，除非是很明显的现象，否则不应该一开始就陷入细节，因此我们一般先查看 “Scheduler latency profile”，我们能通过 Graph 看到整体的调用开销情况，如下：</p>
<p><img src="https://s2.ax1x.com/2020/02/15/1x1K9e.png" alt="image"></p>
<p>演示程序比较简单，因此这里就两块，一个是 <code>trace</code> 本身，另外一个是 <code>channel</code> 的收发。</p>
<h3 id="goroutine-analysis">Goroutine analysis</h3>
<p>第二步看 “Goroutine analysis”，我们能通过这个功能看到整个运行过程中，每个函数块有多少个有 Goroutine 在跑，并且观察每个的 Goroutine 的运行开销都花费在哪个阶段。如下：</p>
<p><img src="https://s2.ax1x.com/2020/02/15/1x1ljA.png" alt="image"></p>
<p>通过上图我们可以看到共有 3 个 goroutine，分别是 <code>runtime.main</code>、<code>runtime/trace.Start.func1</code>、<code>main.main.func1</code>，那么它都做了些什么事呢，接下来我们可以通过点击具体细项去观察。如下：</p>
<p><img src="https://s2.ax1x.com/2020/02/15/1x18Bt.jpg" alt="image"></p>
<p>同时也可以看到当前 Goroutine 在整个调用耗时中的占比，以及 GC 清扫和 GC 暂停等待的一些开销。如果你觉得还不够，可以把图表下载下来分析，相当于把整个 Goroutine 运行时掰开来看了，这块能够很好的帮助我们<strong>对 Goroutine 运行阶段做一个的剖析，可以得知到底慢哪，然后再决定下一步的排查方向</strong>。如下：</p>
<table>
<thead>
<tr>
<th>名称</th>
<th>含义</th>
<th>耗时</th>
</tr>
</thead>
<tbody>
<tr>
<td>Execution Time</td>
<td>执行时间</td>
<td>3140ns</td>
</tr>
<tr>
<td>Network Wait Time</td>
<td>网络等待时间</td>
<td>0ns</td>
</tr>
<tr>
<td>Sync Block Time</td>
<td>同步阻塞时间</td>
<td>0ns</td>
</tr>
<tr>
<td>Blocking Syscall Time</td>
<td>调用阻塞时间</td>
<td>0ns</td>
</tr>
<tr>
<td>Scheduler Wait Time</td>
<td>调度等待时间</td>
<td>14ns</td>
</tr>
<tr>
<td>GC Sweeping</td>
<td>GC 清扫</td>
<td>0ns</td>
</tr>
<tr>
<td>GC Pause</td>
<td>GC 暂停</td>
<td>0ns</td>
</tr>
</tbody>
</table>
<h3 id="view-trace">View trace</h3>
<p>在对当前程序的 Goroutine 运行分布有了初步了解后，我们再通过 “查看跟踪” 看看之间的关联性，如下：</p>
<p><img src="https://s2.ax1x.com/2020/02/15/1x1GHP.png" alt="image"></p>
<p>这个跟踪图粗略一看，相信有的小伙伴会比较懵逼，我们可以依据注解一块块查看，如下：</p>
<ol>
<li>时间线：显示执行的时间单元，根据时间维度的不同可以调整区间，具体可执行 <code>shift</code> + <code>?</code> 查看帮助手册。</li>
<li>堆：显示执行期间的内存分配和释放情况。</li>
<li>协程：显示在执行期间的每个 Goroutine 运行阶段有多少个协程在运行，其包含 GC 等待（GCWaiting）、可运行（Runnable）、运行中（Running）这三种状态。</li>
<li>OS 线程：显示在执行期间有多少个线程在运行，其包含正在调用 Syscall（InSyscall）、运行中（Running）这两种状态。</li>
<li>虚拟处理器：每个虚拟处理器显示一行，虚拟处理器的数量一般默认为系统内核数。</li>
<li>协程和事件：显示在每个虚拟处理器上有什么 Goroutine 正在运行，而连线行为代表事件关联。</li>
</ol>
<p><img src="https://s2.ax1x.com/2020/02/15/1x1YAf.jpg" alt="image"></p>
<p>点击具体的 Goroutine 行为后可以看到其相关联的详细信息，这块很简单，大家实际操作一下就懂了。文字解释如下：</p>
<ul>
<li>Start：开始时间</li>
<li>Wall Duration：持续时间</li>
<li>Self Time：执行时间</li>
<li>Start Stack Trace：开始时的堆栈信息</li>
<li>End Stack Trace：结束时的堆栈信息</li>
<li>Incoming flow：输入流</li>
<li>Outgoing flow：输出流</li>
<li>Preceding events：之前的事件</li>
<li>Following events：之后的事件</li>
<li>All connected：所有连接的事件</li>
</ul>
<h3 id="view-events">View Events</h3>
<p>我们可以通过点击 View Options-Flow events、Following events 等方式，查看我们应用运行中的事件流情况。如下：</p>
<p><img src="https://s2.ax1x.com/2020/02/15/1x1d3Q.png" alt="image"></p>
<p>通过分析图上的事件流，我们可得知这程序从 <code>G1 runtime.main</code> 开始运行，在运行时创建了 2 个 Goroutine，先是创建 <code>G18 runtime/trace.Start.func1</code>，然后再是 <code>G19 main.main.func1</code> 。而同时我们可以通过其 Goroutine Name 去了解它的调用类型，如：<code>runtime/trace.Start.func1</code> 就是程序中在 <code>main.main</code> 调用了 <code>runtime/trace.Start</code> 方法，然后该方法又利用协程创建了一个闭包 <code>func1</code> 去进行调用。</p>
<p><img src="https://s2.ax1x.com/2020/02/15/1x1Dun.png" alt="image"></p>
<p>在这里我们结合开头的代码去看的话，很明显就是 <code>ch</code> 的输入输出的过程了。</p>
<h2 id="结合实战">结合实战</h2>
<p>今天生产环境突然出现了问题，机智的你早已埋好 <code>_ &quot;net/http/pprof&quot;</code> 这个神奇的工具，你麻利的执行了如下命令：</p>
<ul>
<li>curl http://127.0.0.1:6060/debug/pprof/trace?seconds=20 &gt; trace.out</li>
<li>go tool trace trace.out</li>
</ul>
<h3 id="view-trace-1">View trace</h3>
<p>你很快的看到了熟悉的 List 界面，然后不信邪点开了 View trace 界面，如下：</p>
<p><img src="https://s2.ax1x.com/2020/02/15/1x1cNT.jpg" alt="image"></p>
<p>完全看懵的你，稳住，对着合适的区域执行快捷键 <code>W</code> 不断地放大时间线，如下：</p>
<p><img src="https://s2.ax1x.com/2020/02/15/1x1ID1.jpg" alt="image"></p>
<p>经过初步排查，你发现上述绝大部分的 G 竟然都和 <code>google.golang.org/grpc.(*Server).Serve.func</code> 有关，关联的一大串也是 <code>Serve</code> 所触发的相关动作。</p>
<p><img src="https://s2.ax1x.com/2020/02/16/3pNw9I.jpg" alt="image"></p>
<p>这时候有经验的你心里已经有了初步结论，你可以继续追踪 View trace 深入进去，不过我建议先鸟瞰全貌，因此我们再往下看 “Network blocking profile” 和 “Syscall blocking profile” 所提供的信息，如下：</p>
<h3 id="network-blocking-profile">Network blocking profile</h3>
<p><img src="https://s2.ax1x.com/2020/02/16/3pNfCn.jpg" alt="image"></p>
<h3 id="syscall-blocking-profile">Syscall blocking profile</h3>
<p><img src="https://s2.ax1x.com/2020/02/16/3pN7bF.jpg" alt="image"></p>
<p>通过对以上三项的跟踪分析，加上这个泄露，这个阻塞的耗时，这个涉及的内部方法名，很明显就是哪位又忘记关闭客户端连接了，赶紧改改改。</p>
<h2 id="总结">总结</h2>
<p>通过本文我们习得了 <code>go tool trace</code> 的武林秘籍，它能够跟踪捕获各种执行中的事件，例如 Goroutine 的创建/阻塞/解除阻塞，Syscall 的进入/退出/阻止，GC 事件，Heap 的大小改变，Processor 启动/停止等等。</p>
<p>希望你能够用好 Go 的两大杀器 pprof + trace 组合，此乃排查好搭档，谁用谁清楚，即使他并不万能。</p>
<h2 id="参考">参考</h2>
<ul>
<li><a href="https://about.sourcegraph.com/go/an-introduction-to-go-tool-trace-rhys-hiltner">https://about.sourcegraph.com/go/an-introduction-to-go-tool-trace-rhys-hiltner</a></li>
<li><a href="https://www.itcodemonkey.com/article/5419.html">https://www.itcodemonkey.com/article/5419.html</a></li>
<li><a href="https://making.pusher.com/go-tool-trace/">https://making.pusher.com/go-tool-trace/</a></li>
<li><a href="https://golang.org/cmd/trace/">https://golang.org/cmd/trace/</a></li>
<li><a href="https://docs.google.com/document/d/1FP5apqzBgr7ahCCgFO-yoVhk4YZrNIDNf9RybngBc14/pub">https://docs.google.com/document/d/1FP5apqzBgr7ahCCgFO-yoVhk4YZrNIDNf9RybngBc14/pub</a></li>
<li><a href="https://godoc.org/runtime/trace">https://godoc.org/runtime/trace</a></li>
</ul>


                                        
                                        
                                        
                                        <div class="rp4wp-related-posts">
                                            <h3>相关文章</h3>
                                            <ul>
                                                
                                                <li>
                                                    <div class="rp4wp-related-post-content">
                                                        <a
                                                            href="https://www.lican.asia/posts/posts/go/talk/2019-06-29-talking-grpc/">从实践到原理，带你参透 gRPC</a>
                                                    </div>
                                                </li>
                                                
                                                <li>
                                                    <div class="rp4wp-related-post-content">
                                                        <a
                                                            href="https://www.lican.asia/posts/posts/go/grpc-gateway/2019-06-22-grpc-gateway-tls/">「连载四」gRPC&#43;gRPC Gateway 能不能不用证书？</a>
                                                    </div>
                                                </li>
                                                
                                                <li>
                                                    <div class="rp4wp-related-post-content">
                                                        <a
                                                            href="https://www.lican.asia/posts/posts/go/talk/2019-06-16-defer-loss/">Go1.12 defer 会有性能损耗，尽量不要用？</a>
                                                    </div>
                                                </li>
                                                
                                                <li>
                                                    <div class="rp4wp-related-post-content">
                                                        <a
                                                            href="https://www.lican.asia/posts/posts/go/defer/2019-05-27-defer/">深入理解 Go defer</a>
                                                    </div>
                                                </li>
                                                
                                                <li>
                                                    <div class="rp4wp-related-post-content">
                                                        <a
                                                            href="https://www.lican.asia/posts/posts/go/panic/2019-05-21-panic-and-recover/">深入理解 Go panic and recover</a>
                                                    </div>
                                                </li>
                                                
                                            </ul>
                                        </div>
                                        
                                        
                                    </div>

                                    
                                    
                                    

                                    
                                    <div class="post-meta">
                                        
                                        
                                        <div class="post-tags">
                                            <ul>
                                            
                                            <li>
                                                <a href="/tags/go" title="View all posts tagged match">go</a>
                                            </li>
                                            
                                            </ul>
                                        </div>
                                        
                                        
                                        <nav class="further-reading">
                                            
                                            <div class="previous">
                                                <span>&lt;&lt; Prev</span>
                                                <a href="https://www.lican.asia/posts/posts/go/talk/2019-06-29-talking-grpc/"
                                                    rel="prev">从实践到原理，带你参透 gRPC</a> </div>
                                            
                                            
                                            <div class="next">
                                                <span>Next >></span>
                                                <a href="https://www.lican.asia/posts/posts/go/tools/2019-08-19-godebug-sched/">用 GODEBUG 看调度跟踪</a> 
                                            </div>
                                            
                                        </nav>
                                    </div>
                                    
                                    

                                    
                                    
                                    

                                </div>
                            </article>
                        </div>
                    </div>
                </section>
                <aside class="sidebar sidebar-primary" id="sidebar-primary" role="complementary">
    <h1 class="screen-reader-text">Sidebar</h1>
    

    
    
    <section id="text-2" class="widget widget_text">
        <div class="textwidget">
            
            <div id="profile">
                <div id="profile_picture"><img src="https://www.lican.asia/logo/logo.png"></div>
                <div id="profile_intro">
                    <p><span class="name">Lican</span></p>
                    <p class="intro">全栈开发者，爱好造轮子。</p>
                </div>
            </div>
            
            <p>
                <script type="text/javascript">
                    (function ($) {
                        $(document).ready(function () {
                            var menuPrimaryContainer = $('#menu-primary-container');
                            var profile = $('#text-2');
                            $('#toggle-navigation').click(function () {
                                if (menuPrimaryContainer.hasClass('open')) {
                                    profile.removeClass('open');
                                } else {
                                    profile.addClass('open');
                                }
                            });
                        });
                    })(jQuery);
                </script>
            </p>
        </div>
    </section>
    
    
    
    
    
    <section id="text-5" class="widget widget_text">
        <h2 class="widget-title">开源项目</h2>
        <div class="textwidget">
            <div id="projects" style="line-height: 22px;">
                
                <a href="https://github.com/idoubi/gonews"
                    target="_blank">gonews</a>: &nbsp;Daily news for golang<br>
                
                <a href="https://github.com/idoubi/sql2struct"
                    target="_blank">sql2struct</a>: &nbsp;Generate go struct according to SQL<br>
                
                <a href="https://github.com/idoubi/goz"
                    target="_blank">goz</a>: &nbsp;Request library used in golang<br>
                
        </div>
    </section>
    
    

    
    
    
    
    <section id="qrcode" class="widget widget_media_image">
        <h2 class="widget-title">微信公众号</h2>
        <img width="258" height="258"
            src="https://www.lican.asia/wechat/lican.png"
            class="image wp-image-5514  attachment-full size-full" alt=""
            style="max-width: 100%; height: auto;"
            sizes="(max-width: 258px) 100vw, 258px">
    </section>
    
    

    
    
    

    
    
    

    
    
    
    
</aside>
            </div>
        </div>

        <footer id="site-footer" class="site-footer" role="contentinfo">
    <div class="max-width">
    </div>
    <div class="footer">
        <div id="footercontent">
            © lican.asia All rights reserved<br/>
            Built with Hugo Theme <a href="https://github.com/idoubi/hugo-theme-period" target="_blank">Period</a>
        </div>
    </div>
</footer>

<script>
    var _hmt = _hmt || [];
    (function() {
      var hm = document.createElement("script");
      hm.src = "https://hm.baidu.com/hm.js?e8351b6d4626d5881d439ea1f6184baa";
      var s = document.getElementsByTagName("script")[0]; 
      s.parentNode.insertBefore(hm, s);
    })();
</script>
    
    
    </div>
    
</body>

</html>